fix(test): drive the shared-fetch follower's bounded wait to completion - #3631
Conversation
`deno test` exited 1 after reporting zero failures:
ok | 376 passed (3341 steps) | 0 failed (1m14s)
error: Promise resolution is still pending but the event loop has already resolved
That is Deno reporting a promise it was awaiting while the event loop went
empty. It ejected PRs #3592, #3599, #3605 and release PR #3625 from the merge
queue and blocked a local `git push`, and it looked shard-agnostic because it
was seen on coverage shards 1/8, 4/8 and 6/8.
It is one test. `deno test --parallel` prints a file's tests as they finish, so
a file that hangs mid-run still reports the tests that already passed and then
stops. Four independent failing shard logs all truncate the same file after the
same twelve tests: `src/transforms/esm/http-cache.test.ts`, cut off at "returns
a signal-less cache follower after its bounded wait". The shard varied only
because files moved between shards as the tree changed.
The test installs `FakeTime` and owns the clock. The signal-less follower has no
abort signal, so its only release is its own bounded-wait timer, armed once its
real filesystem work reaches `waitForInFlightFetch`. The test advanced the clock
by a fixed `HTTP_MODULE_FETCH_MAX_WAIT_MS` and waited for that work with
`time.runMicrotasks()`, which never advances real I/O. On a loaded runner the
follower arms its timer after the clock has already moved past its due time, no
later advance runs it, and `await followerOutcome` then waits forever on a fake
timer with nothing left on the event loop.
Reproduced deterministically by advancing the clock synchronously
(`time.tick`), which denies the follower the real I/O turn a loaded runner also
denies it: 100% hang, `0 passed (12 steps)` — the same twelve steps CI printed.
The fix drives the work instead of assuming a span reaches it. Waiting for both
callers to share the flight now yields to the real event loop, and the follower
is released by running scheduled fake timers one at a time until it settles,
with a step budget so a genuinely stuck wait fails loudly instead of hanging.
Adds a regression test for the property that matters: a bounded wait whose timer
landed past a single fixed advance still gets run. It fails cleanly against the
old fixed-advance approach.
Verified: the deterministic harness that hung 100% before now passes; the file
runs clean under load where it previously hung.
|
Warning Review limit reached
Next review available in: 3 minutes Enable usage-based reviews in Billing to review now. Otherwise, wait until the next included review is available. How can I continue?After more reviews become available, a review can be triggered using the To avoid repeated limits, reduce automatic review volume by pausing incremental auto-reviews earlier, using label-based review opt-in, excluding WIP or generated PR titles, or requesting reviews manually when the PR is ready. If your team needs uninterrupted high-volume reviews, an organization admin can enable usage-based reviews. How do review limits work?CodeRabbit enforces per-developer PR review limits for each organization. Most developers receive the normal plan review availability. For paid Pro and Pro+ PR reviews, CodeRabbit uses adaptive limits for sustained high-volume activity. When a developer's recent PR review activity reaches the 95th percentile or higher among CodeRabbit users, additional reviews become available more gradually as earlier reviews age out of the rolling window. Please refer docs for additional details. Review details⚙️ Run configurationConfiguration used: Repository UI Review profile: CHILL Plan: Pro Plus Run ID: 📒 Files selected for processing (1)
Comment |
The failure
A fully passing unit run exits 1:
Zero failures, then a non-zero exit. Deno prints that when it is awaiting a
promise and the event loop goes empty underneath it — the awaited work can no
longer make progress, so the process aborts.
It ejected #3592, #3599, #3605 and release PR #3625 from the merge queue today
and blocked a local
git push. Each ejection costs a full queue cycle.It is one test, not a shard problem
It looked shard-agnostic — reported across coverage shards 1/8, 3/8, 4/8, 5/8
and 8/8, and sharding is
index % 8over a sorted file list, so no single filecan sit in five shards. The four failing logs I could retrieve cover shards 1/8,
4/8 and 6/8.
It is still one file.
deno test --parallelstreams a file's tests as theyfinish, so a file that hangs part-way through still reports the tests that
already passed and then simply stops — the file is present in the log but
truncated, and its remaining tests are never counted. Reconstructing each
failing shard's expected file list and diffing it against the tests actually
reported gives, in every case, exactly one file with no completion line:
6f30f87d5mergesrc/transforms/esm/http-cache.test.tsmainsrc/transforms/esm/http-cache.test.ts64d6850d8mergesrc/transforms/esm/http-cache.test.ts07683f134mergesrc/transforms/esm/http-cache.test.tsSame file, same twelve tests, every time. The thirteenth test is where it stops:
"returns a signal-less cache follower after its bounded wait". The shard
number varied only because files moved between shards as the tree changed
(#3596 moved
cli/templatestotemplates/, for one).Root cause
The test installs
FakeTime, so it owns the clock: nothing advances unless thetest advances it.
The follower under test is deliberately signal-less — it passes no abort signal,
so
waitForSharedInFlightHttpFetchgives it exactly one bounded wait and itsonly release is its own timer, armed inside
waitForInFlightFetchonce thefollower's real filesystem work reaches that call.
The test waited for that work with
time.runMicrotasks(), which drainsmicrotasks but never advances real I/O, and then advanced the clock by a fixed
HTTP_MODULE_FETCH_MAX_WAIT_MS. On a loaded runner the follower arms its timerafter the clock has already moved past its due time. No later advance ever
runs it, and
await followerOutcomeis then waiting on a fake timer while thereal event loop is empty — precisely the state Deno reports.
Both known symptoms of this test are the same race: the earlier
AssertionErroratassertEquals(followerSettled, true)was the follower notbeing ready yet; awaiting it instead turned the same race into a hang.
Reproduction
Deterministic: advance the clock synchronously with
time.tick(...)instead oftime.tickAsync(...), which denies the follower the real event-loop turn aloaded runner also denies it. On unmodified
mainthat hangs 100% with theexact CI signature:
0 passed (12 steps)— the same twelve steps every CI log truncated at.Natural: running the whole file repeatedly under heavy load reproduces it
without any modification. Captured live with the follower's state at the moment
of the hang:
next=true— a fake timer is scheduled;waiters=2— the follower is stillinside its bounded wait, holding the timer nothing will run. Every passing run
shows
settled=true next=false waiters=1.--trace-leaksdoes not help here: this is not a leaked op. The op count iszero, which is exactly why the loop drains.
The fix
Drive the work rather than assume a fixed span reaches it.
loop (
Deno.stat) as the file's existingrunNextFakeTimerhelper alreadydoes, instead of only draining microtasks — the follower gets there through
real filesystem work.
runFakeTimersUntil, which runs scheduled faketimers one at a time until it settles. A wait is reachable whenever it is
armed, in any order.
hang, so this can never again silently drop a whole test file.
No sanitizer opt-out (the ratchet stays 404/404), no blanket catch, no sleep, no
skipped test.
Regression test
"runs a bounded wait whose timer landed past a fixed clock advance" encodes the
property that matters: a wait armed past a single fixed advance still gets run.
Verified red against the old approach — replacing the helper body with the
previous fixed advance fails it cleanly, no hang:
Verification
5/5 hang before the fix, 5/5 clean after (
1 passed (74 steps)each).The pre-fix rate at the same load was 1 in 10; 100 clean runs put that at
p ≈ 3e-5.
deno task test:unit(pre-push gate): green.Sanitizer opt-out baseline ok: 404/404.src/transforms/esm/http-cache.test.tscurrently sits in coverage shard 4/8,which is green on this PR along with the other seven.
Not changed
runNextFakeTimer's two other callers already wait for a timer to exist beforerunning it, so they cannot advance past an unarmed wait — the exact defect here.
They are left alone. To be precise about what that does and does not buy: each
runs a single timer, so if one of them ever needed a second one it would have
the same shape, and
runFakeTimersUntilis right there. Neither has shown up inany failing log, so converting them now would be a speculative change to passing
tests.